Closed Bug 1615045 Opened 5 years ago Closed 5 years ago

ThreadSanitizer: data race [@ mozilla::scache::StartupCache::WriteToDisk] vs. [@ mozilla::scache::StartupCache::WriteToDisk]

Categories

(Core :: XPCOM, defect)

x86_64
Linux
defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla75
Tracking Status
firefox-esr68 --- unaffected
firefox73 --- unaffected
firefox74 --- unaffected
firefox75 --- fixed

People

(Reporter: decoder, Assigned: alexical)

References

(Blocks 1 open bug, Regression)

Details

(Keywords: regression)

Attachments

(5 files)

The attached crash information was detected while running CI tests with ThreadSanitizer on autoland revision 7be6903300cfb83220957c288700846566752fa8.

This looks like a race at shutdown where StartupCache::WriteToDisk is racing with itself to write value->mHeaderOffsetInFile.

General information about TSan reports

Why fix races?

Data races are undefined behavior and can cause crashes as well as correctness issues. Compiler optimizations can cause racy code to have unpredictable and hard-to-reproduce behavior.

Rating

If you think this race can cause crashes or correctness issues, it would be great to rate the bug appropriately as P1/P2 and/or indicating this in the bug. This makes it a lot easier for us to assess the actual impact that these reports make and if they are helpful to you.

False Positives / Benign Races

Typically, races reported by TSan are not false positives [1], but it is possible that the race is benign. Even in this case it would be nice to come up with a fix if it is easily doable and does not regress performance. Every race that we cannot fix will have to remain on the suppression list and slows down the overall TSan performance. Also note that seemingly benign races can possibly be harmful (also depending on the compiler, optimizations and the architecture) [2][3].

[1] One major exception is the involvement of uninstrumented code from third-party libraries.
[2] http://software.intel.com/en-us/blogs/2013/01/06/benign-data-races-what-could-possibly-go-wrong
[3] How to miscompile programs with "benign" data races: https://www.usenix.org/legacy/events/hotpar11/tech/final_files/Boehm.pdf

Suppressing unfixable races

If the bug cannot be fixed, then a runtime suppression needs to be added in mozglue/build/TsanOptions.cpp. The suppressions match on the full stack, so it should be picked such that it is unique to this particular race. The bug number of this bug should also be included so we have some documentation on why this suppression was added.

Assignee: nobody → choller
Status: NEW → ASSIGNED
Pushed by shindli@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/ce8b0554fa61 Add temporary TSan suppression for StartupCache. r=froydnj CLOSED TREE

leave-open for removing the suppression again after either the bug is fixed or the regressing changeset has been backed out.

Keywords: leave-open

This was just left in, and does not need to be here. We want to be
spawning the background thread here which we will wait on from
xpcom-shutdown.

Pushed by dothayer@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/56ef1d43a305 Remove extraneous extra write to StartupCache r=froydnj https://hg.mozilla.org/integration/autoland/rev/c0414b3adbe8 Remove StartupCache tsan race suppression r=froydnj

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&group_state=expanded&selectedJob=288967829&resultStatus=testfailed%2Cbusted%2Cexception&revision=c0414b3adbe85a8c901b5f45469a6ba1364a1dec&searchStr=linux64-tsan%2Copt%2Cmochitests%2Ctest-linux64-tsan%2Fopt-mochitest-e10s-4%2Cm%284%29

Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=288967829&repo=autoland

Backout link: https://hg.mozilla.org/integration/autoland/rev/717b7cc1424a2a35d075cc7ca8ece7d1cd8df0d2

[task 2020-02-14T17:04:45.873Z] 17:04:45     INFO - GECKO(2678) |   Thread T7 'StartupCache' (tid=2926, running) created by main thread at:
[task 2020-02-14T17:04:45.873Z] 17:04:45     INFO - GECKO(2678) |     #0 pthread_create /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/tsan/rtl/tsan_interceptors.cc:967:3 (firefox+0x571ab)
[task 2020-02-14T17:04:45.873Z] 17:04:45     INFO - GECKO(2678) |     #1 _PR_CreateThread /builds/worker/workspace/build/src/nsprpub/pr/src/pthreads/ptthread.c:458:14 (libnspr4.so+0x3dc53)
[task 2020-02-14T17:04:45.874Z] 17:04:45     INFO - GECKO(2678) |     #2 PR_CreateThread /builds/worker/workspace/build/src/nsprpub/pr/src/pthreads/ptthread.c:533:12 (libnspr4.so+0x32152)
[task 2020-02-14T17:04:45.875Z] 17:04:45     INFO - GECKO(2678) |     #3 mozilla::scache::StartupCache::MaybeSpawnWriteThread() /builds/worker/workspace/build/src/startupcache/StartupCache.cpp:702:18 (libxul.so+0x63651fd)
[task 2020-02-14T17:04:45.875Z] 17:04:45     INFO - GECKO(2678) |     #4 mozilla::scache::StartupCache::WriteTimeout(nsITimer*, void*) /builds/worker/workspace/build/src/startupcache/StartupCache.cpp:683:20 (libxul.so+0x6365345)
[task 2020-02-14T17:04:45.877Z] 17:04:45     INFO - GECKO(2678) |     #5 nsTimerImpl::Fire(int) /builds/worker/workspace/build/src/xpcom/threads/nsTimerImpl.cpp:562:7 (libxul.so+0xa6256f)
[task 2020-02-14T17:04:45.877Z] 17:04:45     INFO - GECKO(2678) |     #6 nsTimerEvent::Run() /builds/worker/workspace/build/src/xpcom/threads/TimerThread.cpp:259:11 (libxul.so+0xa62092)
[task 2020-02-14T17:04:45.878Z] 17:04:45     INFO - GECKO(2678) |     #7 nsThread::ProcessNextEvent(bool, bool*) /builds/worker/workspace/build/src/xpcom/threads/nsThread.cpp:1220:14 (libxul.so+0xa6c583)
[task 2020-02-14T17:04:45.878Z] 17:04:45     INFO - GECKO(2678) |     #8 NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/workspace/build/src/xpcom/threads/nsThreadUtils.cpp:481:10 (libxul.so+0xa71182)
[task 2020-02-14T17:04:45.879Z] 17:04:45     INFO - GECKO(2678) |     #9 mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /builds/worker/workspace/build/src/ipc/glue/MessagePump.cpp:109:5 (libxul.so+0x12a7a6e)
[task 2020-02-14T17:04:45.880Z] 17:04:45     INFO - GECKO(2678) |     #10 RunInternal /builds/worker/workspace/build/src/ipc/chromium/src/base/message_loop.cc:315:10 (libxul.so+0x123effc)
[task 2020-02-14T17:04:45.880Z] 17:04:45     INFO - GECKO(2678) |     #11 RunHandler /builds/worker/workspace/build/src/ipc/chromium/src/base/message_loop.cc:308:3 (libxul.so+0x123effc)
[task 2020-02-14T17:04:45.880Z] 17:04:45     INFO - GECKO(2678) |     #12 MessageLoop::Run() /builds/worker/workspace/build/src/ipc/chromium/src/base/message_loop.cc:290:3 (libxul.so+0x123effc)
[task 2020-02-14T17:04:45.882Z] 17:04:45     INFO - GECKO(2678) |     #13 nsBaseAppShell::Run() /builds/worker/workspace/build/src/widget/nsBaseAppShell.cpp:137:27 (libxul.so+0x46f34b3)
[task 2020-02-14T17:04:45.883Z] 17:04:45     INFO - GECKO(2678) |     #14 nsAppStartup::Run() /builds/worker/workspace/build/src/toolkit/components/startup/nsAppStartup.cpp:272:30 (libxul.so+0x6208445)
[task 2020-02-14T17:04:45.883Z] 17:04:45     INFO - GECKO(2678) |     #15 XREMain::XRE_mainRun() /builds/worker/workspace/build/src/toolkit/xre/nsAppRunner.cpp:4566:22 (libxul.so+0x631b84a)
[task 2020-02-14T17:04:45.883Z] 17:04:45     INFO - GECKO(2678) |     #16 XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/workspace/build/src/toolkit/xre/nsAppRunner.cpp:4701:8 (libxul.so+0x631c3ad)
[task 2020-02-14T17:04:45.883Z] 17:04:45     INFO - GECKO(2678) |     #17 XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/workspace/build/src/toolkit/xre/nsAppRunner.cpp:4752:21 (libxul.so+0x631c774)
[task 2020-02-14T17:04:45.883Z] 17:04:45     INFO - GECKO(2678) |     #18 mozilla::BootstrapImpl::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/workspace/build/src/toolkit/xre/Bootstrap.cpp:45:12 (libxul.so+0x6325482)
[task 2020-02-14T17:04:45.884Z] 17:04:45     INFO - GECKO(2678) |     #19 do_main /builds/worker/workspace/build/src/browser/app/nsBrowserApp.cpp:217:22 (firefox+0xc8a57)
[task 2020-02-14T17:04:45.884Z] 17:04:45     INFO - GECKO(2678) |     #20 main /builds/worker/workspace/build/src/browser/app/nsBrowserApp.cpp:331:16 (firefox+0xc8a57)
[task 2020-02-14T17:04:45.885Z] 17:04:45     INFO - GECKO(2678) | SUMMARY: ThreadSanitizer: data race /builds/worker/workspace/build/src/startupcache/StartupCache.cpp:555:16 in mozilla::scache::StartupCache::WriteToDisk()
[task 2020-02-14T17:04:45.886Z] 17:04:45     INFO - GECKO(2678) | ==================
[task 2020-02-14T17:04:45.946Z] 17:04:45     INFO - GECKO(2678) | Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=97.8664) [GFX1-]: Receive IPC close with reason=AbnormalShutdown
[task 2020-02-14T17:04:45.947Z] 17:04:45     INFO - GECKO(2678) | Exiting due to channel error.
[task 2020-02-14T17:04:47.006Z] 17:04:47     INFO - TEST-INFO | Main app process: killed by SIGIOT
[task 2020-02-14T17:04:47.007Z] 17:04:47     INFO - Buffered messages finished
[task 2020-02-14T17:04:47.009Z] 17:04:47    ERROR - TEST-UNEXPECTED-FAIL | Last test finished | application terminated with exit code -6
Flags: needinfo?(choller)
Flags: needinfo?(choller) → needinfo?(dothayer)
Assignee: choller → dothayer

Reordering the mWrittenOnce check should be sufficient to eliminate
the data race; however, I made mWrittenOnce an atomic just to reduce
the fragility of this since it is intended to be written from and
read to on multiple threads.

Depends on D62849

Pushed by dothayer@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/e69118b08517 Remove extraneous extra write to StartupCache r=froydnj https://hg.mozilla.org/integration/autoland/rev/c68528f299eb Remove StartupCache tsan race suppression r=froydnj https://hg.mozilla.org/integration/autoland/rev/7504ff45bac4 Remove mWrittenOnce data race r=decoder
Flags: needinfo?(dothayer)
Regressed by: 1607505
Has Regression Range: --- → yes

== Change summary for alert #24974 (as of Tue, 18 Feb 2020 06:50:25 GMT) ==

Improvements:

64% tp5n main_normal_fileio windows10-64-shippable opt e10s stylo 2,770,171.56 -> 997,093.33
62% tp5n main_normal_fileio windows10-64-shippable-qr opt e10s stylo 2,505,922.75 -> 943,750.75
61% tp5n main_normal_fileio windows10-64-shippable-qr opt e10s stylo 2,627,381.44 -> 1,016,842.67

For up to date results, see: https://treeherder.mozilla.org/perf.html#/alerts?id=24974

Can we close this or is the leave-open still needed?

Flags: needinfo?(dothayer)

Oh, sorry, yes this can be closed.

Flags: needinfo?(dothayer)

Great, thanks!

Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Keywords: leave-open
Resolution: --- → FIXED
Target Milestone: --- → mozilla75
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: